… licence when you use it as a noun and license when you use it as a verb.
- Log Files
- Expected Messages
- Undesired Messages
- Applicable TCL Commands
- Caching
- Automating Checks
- Connectivity
- Availability
- Winning the Licence Race
- Verifying Vivado Can See The Licences
- Integrating Checks into TCL for Vivado
- Fuller TCL Error Handling
- Shelling out to Bash
- So what was the problem?
- References
We recently had an issue where our build server was failing to complete very long (4+ hour) compilations because it was unable to reach the licence server and acquire the required licence. When this happens on builds left to complete over the weekend this is very frustrating.
The first thing is to make sure we know the difference between what good and bad looks like. (Oh, and how to spell 'licence' correctly!)
Log Files
Expected Messages
Here are two examples of successfully getting a licence, one for each 'feature' of synthesis and implementation. The Vivado transcripts show the successful acquisition and release of either feature.
Attempting to get a license for feature 'Synthesis' and/or device 'xcku060' INFO: [Common 17-349] Got license for feature 'Synthesis' and/or device 'xcku060' ... INFO: [Common 17-83] Releasing license: Synthesis XX Infos, XX Warnings, XX Critical Warnings and XX Errors encountered. synth_design completed successfully
Attempting to get a license for feature 'Implementation' and/or device 'xcku060' INFO: [Common 17-349] Got license for feature 'Implementation' and/or device 'xcku060' ... Routing Is Done. INFO: [Common 17-83] Releasing license: Implementation XX Infos, XX Warnings, XX Critical Warnings and XX Errors encountered. route_design completed successfully
Phase 2 Generate And Synthesize Debug Cores INFO: [Chipscope 16-329] Generating Script for core instance : dbg_hub INFO: [IP_Flow 19-3806] Processing IP xilinx.com:ip:xsdbm:3.0 for cell dbg_hub_CV. get_clocks: Time (s): cpu = 00:01:30 ; elapsed = 00:00:26 . Memory (MB): peak = 6961.094 ; gain = 0.000 ; free physical = 12306 ; free virtual = 40138 Netlist sorting complete. Time (s): cpu = 00:00:00.30 ; elapsed = 00:00:00.31 . Memory (MB): peak = 6961.094 ; gain = 0.000 ; free physical = 12304 ; free virtual = 40137 Phase 2 Generate And Synthesize Debug Cores | Checksum: 1568f6c6b
The log file entries are different for write_debug_probes, with [IP_Flow 19-3806] being the best way to verify a licence was acquired.
Undesired Messages
Now for an example of failing to get a licence. These transcript entries provide unique strings to search for to test for failure.
Attempting to get a license for feature 'Synthesis' and/or device 'xcku060' WARNING: [Common 17-348] Failed to get the license for feature 'Synthesis' and/or device 'xcku060'. Explanation: Cannot connect to a license server running the xilinxd licensing daemon at the specified port. Resolution: Check the status of your licenses in the Vivado License Manager. For debug help search Xilinx Support for "Licensing FAQ". XX Infos, XX Warnings, XX Critical Warnings and XX Errors encountered. synth_design failed ERROR: [Common 17-345] A valid license was not found for feature 'Synthesis' and/or device 'xcku060'. Please run the Vivado License Manager for assistance in determining which features and devices are licensed for your system. Resolution: Check the status of your licenses in the Vivado License Manager. For debug help search Xilinx Support for "Licensing FAQ". If you are using a license server, verify that the license server is up and running a version of the xilinx daemon that is compatible with the version of Xilinx software that you are using. Please note that Vivado 2017.3 and later requires upgrading your license server tools to the Flex 11.14.1 tools. Please confirm with your license admin that the correct version of the license server tools are installed. ERROR: [Common 17-53] User Exception: No open design. Please open an elaborated, synthesized or implemented design before executing this command.
After synth_ip has been called on a series of IP cores Vivado seemed to stop getting a licence. A few 10s of IP cores later it recovers and starts acquiring them again. A few 10s of IP cores later it failed again. So we need a way to test the connection to the licence server sampled over a period of time (hours).
Phase 2 Generate And Synthesize Debug Cores INFO: [Chipscope 16-329] Generating Script for core instance : dbg_hub INFO: [IP_Flow 19-3806] Processing IP xilinx.com:ip:xsdbm:3.0 for cell dbg_hub_CV. The following Error logs belongs to dbg_hub ERROR: [Common 17-345] A valid license was not found for feature 'Synthesis' and/or device 'xcku060'. Please run the Vivado License Manager for assistance in determining ERROR: [IP_Flow 19-3805] Failed to generate and synthesize debug IPs. error copying "/path/.Xil_fpga/Vivado-31728-localhost.localdomain/dc_drv.0/dc/prj_ip.runs/dbg_hub_synth_1/dbg_hub.dcp": no such file or directory ERROR: [Chipscope 16-330] Synthesis of Debug Cores has failed
This example shows the transcript having [Common 17-345] errors instead of [Common 17-348], so any log file parsing needs to account for this.
Applicable TCL Commands
These commands do require a licence:
- synth_ip
- synth_design
- opt_design
- place_design
- route_design
- write_debug_probes
- write_bitstream
These commands do not require a licence:
- link_design
- write_checkpoint
Therefore do not try to loop while no licence has been acquired with link_design, as you 'll be looping infinitely long (like I was).
Caching
Constructing a soak test was hindered by an inability to just set XILINXD_LICENSE_FILE="" and re-run for the failure case. The option circled here on the Java-based GUI suggests there is a licence cache that might be providing the information I had explicitly nulled in order to cause a failure.
The code below shows how to list the cache under Windows from the registry. The equivalent under Linux is to display the contents of a file called ~/.flexlmrc.
reg query "HKEY_CURRENT_USER\Software\FLEXlm License Manager"
HKEY_CURRENT_USER\Software\FLEXlm License Manager
XILINXD_LICENSE_FILE REG_SZ port2@host2
HKEY_CURRENT_USER\Software\FLEXlm License Manager\Borrow
The following command will remove the cached licence file entry so that setting XILINXD_LICENSE_FILE="" to nothing now correctly causes the script to fails. The equivalent under Linux is to delete the file ~/.flexlmrc.
reg delete "HKEY_CURRENT_USER\Software\FLEXlm License Manager" /v XILINXD_LICENSE_FILE
# Redirect stderr as it complains when the key is absent and hence cannot be deleted.
reg delete "HKEY_CURRENT_USER\Software\FLEXlm License Manager" /v XILINXD_LICENSE_FILE /f 2> /dev/null
Automating Checks
The Xilinx Forums contain plenty of ideas for what you might do to resolve licence problems, so here are some actual attempts to script the process under Cygwin for Windows. Similar works for Linux, but the output of some command, e.g. ping, differ and the parsing of their stdout needs to be adapted as do their command line switches.
Connectivity
# Test the Xilinx licence server can be reached.
#
# NB. \x27 is ' (apostrophe)
function reach_licence_server () {
if [ -n "${XILINXD_LICENSE_FILE}" ]; then
EC=$(lmutil lmdiag -n -c ${XILINXD_LICENSE_FILE} | sed -n '
/Can\x27t fetch the requested Information!!/ {
c 1
p
}
/License file:/ {
c 0
p
}
')
echo "${EC}"
return ${EC}
else
echo "1"
return 1
fi
}
The above code checks that there is a responsive licence server at the host pointed to by XILINXD_LICENSE_FILE.
Availability
The code below can check if there is a licence available, or more precisely how many licences are available for acquiring. However this is all done in Bash script not TCL, so would be used before calling vivado with a TCL compilation script, or could test transient problems if allowed to loop once every few minutes over several hours.
# Return the actual number of licences available for a feature.
#
# Parameters
# 1) Licence type - either "Synthesis" or "Implementation"
#
# Usage: LIC_NUM=$(vivado_licences_available "Synthesis")
#
function vivado_licences_available() {
local feature=${1}
if [[ ("${feature}" != "Synthesis") && ("${feature}" != "Implementation") ]]; then
echo "Error - First parameter is the licence 'feature' and must be either 'Synthesis' or 'Implementation'. You provided '${feature}'." >&2
exit 1
fi
if [ -n "${XILINXD_LICENSE_FILE}" ]; then
lmslog="$(lmutil lmstat -c ${XILINXD_LICENSE_FILE} -S xilinxd -a)"
if [ "${LOGFILE}" != "none" ]; then
echo "" >> ${LOGFILE}
echo "** Called ${FUNCNAME[0]}: ${feature}" >> ${LOGFILE}
echo "${lmslog}" >> ${LOGFILE}
fi
read feature_parsed total used <<< $(sed -n '
/Users of '${feature}'/ {
s/Users of \([^:]\+\):\s*(Total of \([0-9\+]\) licenses* issued; Total of \([0-9\+]\) licenses* in use)/\1 \2 \3/
p
}
' <<< "${lmslog}")
if [ "${feature_parsed}" == "${feature}" ]; then
echo "$(( total - used ))"
return 0
else
echo "Error - feature returned from licence server was '${feature_parsed}', but requested '${feature}'." >&2
echo "-"
return 1
fi;
else
return 1
fi
}
Winning the Licence Race
The code below could be used to test that Vivado did actually get the licence without losing any race to grab it.
# Parse a Vivado log file to find the last run synthesis' licence status.
#
# Usage: was_vivado_licence_acquired /path/vivado.log
#
# Returns: a single line string either "true" or "false"
#
function was_vivado_licence_acquired() {
local logfile=${1}
if [ -z "${logfile}" ]; then
echo "Error - First parameter must specify the Vivado log file to parse." >&2
exit 1
fi
if [ -f "${logfile}" ]; then
sed -n '
# For write_debug_probes
/\[Common 17-345\]/ {
c\
Licence: false
p
}
/\[Common 17-348\]/ {
c\
Licence: false
p
}
/\[Common 17-349\]/ {
c\
Licence: true
p
}
# For write_debug_probes
/\[IP_Flow 19-3806\]/ {
c\
Licence: true
p
}
' ${logfile} | tail -1
return 0
else
echo "Error: '${logfile}' not found."
return 1
fi
}
Verifying Vivado Can See The Licences
These functions can be placed before and after a trivial synthesis as part of a test that Vivado can see the licence server. An extract follows below.
vivado \
-nojournal \
-tempDir ${TMP} \
-notrace \
-log ${LOGFILE} \
-mode batch \
-source ${TCLSCRIPT} > /dev/null
VIV=${?}
echo -e " * $(pass_fail ${VIV}) - Trivial synthesis task"
[ -f ${LOGFILE} ]
echo -e " * $(pass_fail ${?}) - Log file created"
if [ -f ${LOGFILE} ]; then
declare -a LICS=(
$(sed -n '
# /\[Common 17-53\]/ {
# c\
#Error of some kind
# p
# }
# /\[Common 17-206\]/ {
# c\
#Exited
# p
# }
# /\[Common 17-345\]/ {
# c\
#No Licence
# p
# }
/\[Common 17-348\]/ {
#No Licence
c\
1
p
}
/\[Common 17-349\]/ {
#Got Licence
c\
0
p
}
# /\[Common 17-83\]/ {
# c\
#Released Licence
# p
# }
' ${THISDIR}/vivado.log)
)
if [[ (${#LICS[@]} -eq 2) && (${LICS[0]} == "0") && (${LICS[1]} == "0") ]]; then
EC=0
else
EC=1
fi
echo -e " * $(pass_fail ${EC}) - Got licences for both Synthesis and Implementation"
Where the TCLSCRIPT variable refers to a TCL script file whose contents might be as follows:
set script [file tail [file normalize [info script]]]
if {[info exists env(XILINXD_LICENSE_FILE)]} {
puts "Note - $script: 'XILINXD_LICENSE_FILE' defined as '$env(XILINXD_LICENSE_FILE)'."
} else {
error "Error - $script: 'XILINXD_LICENSE_FILE' is undefined."
}
create_project synth -in_memory -force
set_property PART xcku060-ffva1156-2-i [current_project]
set_property target_language VHDL [current_project]
# Required for XCI files instead of XCIX (Core Container) files in Vivado 2019.2
set_property coreContainer.enable 0 [current_project]
read_vhdl -vhdl2008 ./trivial.vhd
set_property top trivial [current_fileset]
update_compile_order -fileset [current_fileset]
set_property source_mgmt_mode All [current_project]
update_compile_order -fileset sources_1
# This command exits on failure without giving a non-zero exit code to the shell.
proc do_work {} {
# Requires Synthesis licence
synth_design -name synth -mode out_of_context
# Requires Implementation licence
place_design -directive Default
# Requires Implementation licence
#route_design -directive Explore
}
# catch TCL_ERROR (1), but not TCL_OK (0), TCL_RETURN (2), TCL_BREAK (3) nor TCL_CONTINUE (4)
if {[catch do_work msg options] == 1} {
exit 1
}
exit 0
The above test uses VHDL for a single D-type register (trivial.vhd), therefore it is cheap enough (50-60 seconds run time) to be placed in a periodic loop to soak test over a long period of time.
Integrating Checks into TCL for Vivado
Fuller TCL Error Handling
The method must be to try detecting a licence failure within TCL itself. TCL has error handling routines, so I attempted to catch the error.
proc cause_error {} {
error "Human readable message" "Included in -errorinfo" 3
}
switch [catch cause_error msg options] {
# TCL_OK
0 {
puts "TCL_OK"
}
# TCL_ERROR
1 {
puts "TCL_ERROR"
puts "Message: $msg"
puts "Error code: [dict get $options {-errorcode}]"
dict for {key value} $options {
puts "$key = $value"
}
}
# TCL_RETURN
2 {
puts "TCL_RETURN"
}
# TCL_BREAK
3 {
puts "TCL_BREAK"
}
# TCL_CONTINUE
4 {
puts "TCL_CONTINUE"
}
default {
puts "Default clause - non standard exit code"
}
}
Above is a more comprehensive TCL error handling code snippet you can use. Note that Vivado does not set -errorcode, so this became redundant in these tests when catching synth_design but I wanted to retain the code snippet for future reference. Essentially error returns TCL_ERROR. This is not a constant you can use in your scripts just a value that TCL manuals refer to, probably from the underlying programming language, instead you must use the explicit value "1". This return code should not be confused with -errorinfo which is quite separate, and could be used to indicate more fine grained error information. Essentially, you might get an error because synthesis or implementation having got a licence then failed for the right reasons. Also, I observed that failure to get a licence did not always raise a TCL error, but even if it did the reason for any error cannot be distinguished except by parsing the Vivado log file. This means you have to choose to parse the log file in either TCL or shell out to something like Bash. My choice was to shell out to Bash as it has so many efficient ways to perform the task rather than iterate through the log file pattern matching in TCL or trying to call lmutil from TCL and parse the output.
Shelling out to Bash
Firstly, the Bash script. You need to decide how you want to arrange your Bash functions across different shell scripts. I chose to put mine together and call availability and acquisition checks with different command lines. Or you could separate the two functions to different scripts. The two functions are called via vivado_licence_status and was_vivado_licence_acquired (with a log file parameter).
LOGFILE=${LOGFILE:-none}
# Print out the licence server status. Assumes that PATH is set up correctly.
# Usage: vivado_licence_status
#
# Returns text on stdout as follows:
# Date: 10/06/2021 09:05:45
# Log file: /path/licence.log
# Ping server: alive
# Licence server: alive
# Synthesis licences: 3
# Implementation licences: 4
#
function vivado_licence_status() {
# Turn on logging:
#LOGFILE="$(realpath ${THISDIR}/../misc/licences)/licence.log"
d="Date: $(date "+%d/%m/%Y %H:%M:%S")"
if [ "${LOGFILE}" != "none" ]; then
echo "***************************" >> ${LOGFILE}
echo "${d}" >> ${LOGFILE}
echo "***************************" >> ${LOGFILE}
fi
echo "${d}"
echo "Log file: ${LOGFILE}"
if [ -z "${XILINXD_LICENSE_FILE}" ]; then
echo "Error: XILINXD_LICENSE_FILE undefined"
exit 0
fi
case $(uname -o) in
Cygwin)
PINGOPT="-n 1"
pingtest='
/Request timed out/ {
c 1
p
}
/Reply from/ {
c 0
p
}
'
;;
GNU/Linux)
PINGOPT="-c 1"
pingtest='
/100% packet loss/ {
c 1
p
}
/0% packet loss/ {
c 0
p
}
'
;;
esac
host=$(hostname_lookup $(echo "${XILINXD_LICENSE_FILE}" | sed 's/^.*@\(.*\)$/\1/'))
pinglog=$(ping ${host} ${PINGOPT})
[ "${LOGFILE}" != "none" ] && echo "${pinglog}" >> ${LOGFILE}
if [ "$(sed -n "${pingtest}" <<< "${pinglog}")" == "0" ]; then
echo "Ping server: alive"
else
echo "Ping server: unresponsive"
fi
echo -n "Licence server: "
if reach_licence_server > /dev/null; then
echo "alive"
else
echo "unresponsive"
fi
echo "Synthesis licences: $(vivado_licences_available "Synthesis")"
echo "Implementation licences: $(vivado_licences_available "Implementation")"
[ "${LOGFILE}" != "none" ] && echo "====================================================" >> ${LOGFILE}
}
vivado_licence_status
Date: 10/06/2021 09:05:45 Log file: /path/licence.log Ping server: alive Licence server: alive Synthesis licences: 3 Implementation licences: 4
Secondly TCL script. Now we only need some simple TCL parsing of the more structured results.
# Return a TCL dictionary containing the parsed results from Bash script
# 'licence_diagnostics.sh'.
#
# Usage: puts [get_licence_availability]
#
# Returns:
# {
# date {10/06/2021 09h05m45s}
# logfile /cygdrive/d/git/ccs_shield_pfb48/scripts/misc/licences/licence.log
# ping alive
# server alive
# synthesis 3
# implementation 4
# }
#
proc get_licence_availability {} {
set ret {}
set thisdir [file dirname [file normalize [dict get [info frame 0] file]]]
if {[catch {
set pipe [open |[list bash -c "$thisdir/licence_diagnostics.sh -a 2>/dev/null" ] "r"]
} options]} {
# Failed
error "ERROR in '[file tail [file normalize [dict get [info frame 0] file]]]': Unable to fetch licence server diagnostics. $options"
} else {
# Succeeded
while {[gets $pipe line] >= 0} {
set parts [split $line ":"]
set value [string trim [join [lrange $parts 1 end] ":"]]
switch [lindex $parts 0] {
"Date" {
dict set ret date $value
}
"Log file" {
dict set ret logfile $value
}
"Ping server" {
dict set ret ping $value
}
"Licence server" {
dict set ret server $value
}
"Synthesis licences" {
dict set ret synthesis $value
}
"Implementation licences" {
dict set ret implementation $value
}
"Error" {
dict set ret error $value
}
default {
error "ERROR in '[file tail [file normalize [dict get [info frame 0] file]]]': Unknown selector '[lindex $parts 0]'."
}
}
flush stdout
}
close $pipe
}
return $ret
}
# Parse a Vivado log file to find the last run synthesis' licence status.
#
# Usage: was_vivado_licence_acquired {/path/synth.log}
#
# if {[dict get [was_vivado_licence_acquired "/path/synth.log"] licence]} {
# puts "Yes"
# } else {
# puts "No"
# }
#
# Returns: a single line string either "true" or "false"
#
proc was_vivado_licence_acquired {logfile} {
set ret {}
set thisdir [file dirname [file normalize [dict get [info frame 0] file]]]
if {
[catch {
set pipe [open |[list bash -c "$thisdir/licence_diagnostics.sh -c=$logfile 2>/dev/null" ] "r"]
} options]
} {
# Failed
error "ERROR in '[file tail [file normalize [dict get [info frame 0] file]]]': Unable to fetch log file diagnostics. $options"
} else {
# Succeeded
while {[gets $pipe line] >= 0} {
set parts [split $line ":"]
set value [string trim [join [lrange $parts 1 end] ":"]]
switch [lindex $parts 0] {
"Licence" {
dict set ret licence $value
}
"Error" {
dict set ret error $value
}
}
flush stdout
}
close $pipe
}
return $ret
}
# Call TCL 'script' code inside a wrapper that catches and reports errors and
# loops to retry on failure. This function is very tightly coupled to VIvado's
# *_design commands. Do not use for any random TCL.
#
# Parameters:
# * script - Vivado TCL code quoted in {...}.
# * feature - Either 'synthesis' or 'implementation'
# * logfile - path to the Vivado log file to parse in a format that Cygwin or UNIX can find.
#
# Usage: licence_catch {synth_design -name synth ${SYNTHMODE} ${SYNTHOPTS}}
#
proc licence_catch {script feature logfile} {
if {![string equal $feature "synthesis"] && ![string equal $feature "implementation"]} {
error "Error - 'feature' parameter is '$feature', but must be either 'synthesis' or 'implementation'."
}
while {true} {
set la [get_licence_availability]
puts "Licence Check (before):"
puts " * Date & Time: [dict get $la date]"
if {[dict exists $la error]} {
puts " * Error (availability): [dict get $la error]"
} else {
#puts " * Log file: [dict get $la logfile]"
puts " * Ping: [dict get $la ping]"
puts " * Server: [dict get $la server]"
# These two can return either a non-negative integer or "-"
puts " * Feature '$feature': [dict get $la $feature]"
}
# NB. When [dict get $la $feature] returns "-", this test fails and correctly retries.
if {[dict get $la $feature] > 0} {
# TCL catch on Vivado commands is not so clever. It will catch non-licence errors
# and does not seem to catch _all_ licence errors. Using a log file check instead.
# Run the Vivado command passed in
uplevel $script
# Only exit the loop if we really did get a licence according to the logfile
set acq [was_vivado_licence_acquired $logfile]
puts "Licence Check (after):"
if {[dict exists $acq error]} {
puts " * Error (acquisition): [dict get $acq error]"
} elseif {![dict exists $acq licence]} {
puts " * Licence acquired: Unknown, retrying."
} elseif {[dict get $acq licence]} {
puts " * Licence acquired: Yes, continuing."
break
} else {
puts " * Licence acquired: No, retrying."
}
} else {
# Wait 10s before checking the licence server again
after 10000
}
}
}
From the code you will observe that I have chosen to call my Bash script licence_diagnostics.sh, with two options as follows.
licence_diagnostics.sh -a licence_diagnostics.sh -c=$logfile
Within my Vivado TCL compilation script I can now wrap each synthesis or implementation TCL command as follows.
licence_catch {synth_design -name synth $synthmode $synthopts} synthesis $logfile
licence_catch {synth_ip -name synth $synthmode $synthopts} synthesis $logfile
# Do not wrap this one unless you want an infinite loop!
link_design
licence_catch {opt_design} implementation $logfile
licence_catch {place_design} implementation $logfile
licence_catch {route_design} implementation $logfile
The big down side of my design choice is the tight coupling I have created between TCL and shelling out to a UNIX-Like environment. It does work on Windows with something like Cygwin installed. However, I also have the option of incorporating the Bash functions into the broader Bash compilation scripts that invokes vivado. Your mileage may vary.
So what was the problem?
The licence server had become stuck with a pending action to install a service pack. It is currently unclear why it constantly reboots every hour without ever finishing this installation. A Windows 10 "feature" was introduced a few releases back to reboot "out of busy hours" and the maximum the machine can be set "busy" for is 18 hours so there is always a window to reboot itself. Hence the licence server was dropping out during a reboot, but only out of hours, and the problem did not reoccur for another 18 hours.
As a result of this investigation we have now built in resilience to the lengthy FPGA build process, and should be able to with stand the weekend take down of the licence server for a force upgrade without losing our compilation jobs in Jenkins.